<#
.Synopsis
   Extracts Execution Times from ULS Log
.DESCRIPTION
   Extracts the B4LY tags matching the specified correlation ID mask from the specified ULS file.

   It is also possible to specify a Threshold, so only the slowest Executions are displayed.

   Totalisation is the sum of all Execution time matching the correlationID. 

   IMPORTANT: As some scopes are included in other, the TotalExecTime do not represent the Time for the beginning.
   
 .EXAMPLE
   .\DUMP-ExecutionTime.1.ps1 -file Vince_88050_ULS.log -CorrelationId "*913f689c-a6dc-d0a4-8cee-724e694865a6*" -showTotalColumn

   Extracts all Execution time for correlation ID 913f689c-a6dc-d0a4-8cee-724e694865a6

   The output will be like


   ExecTime   	TotalExecTime	 Monitored Scope
---------- 	-------------	 ------------------------------
    40.603 	      40.603 	 Leaving Monitored Scope (PostResolveRequestCacheHandler).  
    27.523 	      68.126 	 Leaving Monitored Scope (GetFileAndMetaInfo).  
    28.289 	      96.415 	 Leaving Monitored Scope (GetWebPartPageContent).  
    47.070 	     143.485 	 Leaving Monitored Scope (PublishingMobile: Resolve the default or non-default 
    [...CUT...]
16,747.120 	  43,092.380 	 Leaving Monitored Scope (Request (GET:https://msftvrungeb3.sharepoint.com/sites/<PII:H

88 monitored scopes matched, for a total of 43092.38 ms



.EXAMPLE
   
   .\DUMP-ExecutionTime.ps1 -Threshold 2000 -file vrunge_88050_ULS.log 

    Extracts all Execution times above 2000 ms, regardless of their correlation ID. This allows for easy identification of the slowest executions.

Extracting Execution Times above 2000 ms from file c:\vincent\tests\ps_dump-executiontime\vrunge_88050_ULS.log 

The Output will be:

Extracting Execution Times above 2000 ms from file c:\vincent\tests\ps_dump-executiontime\vrunge_88050_ULS.log 
with correlation id matching *

ExecTime   	 Monitored Scope
---------- 	 ------------------------------
 2,282.073 	 Leaving Monitored Scope (DataBinding DataFormWebPart (Cust-K<PII:H101(uyeoIB3fqKZMcSfzsPRP5Vo...
 2,620.962 	 Leaving Monitored Scope (DataBinding DataFormWebPart (Cust-Ohjeet)).  
16,747.120 	 Leaving Monitored Scope (Request (GET:https://msftvrungeb3.sharepoint.com/sites/<PII:H101(...

3 monitored scopes matched, for a total of 21650.16 ms


.EXAMPLE

   dir *log | .\Dump-ExecutionTime.ps1 -Threshold 2000

   Extract all scopes above 2 seconds from all files with LOG extension. 
   Example Output:

Extracting Execution Times above 2000 ms from file C:\vincent\tests\PS_Dump-ExecutionTime\anotherlog.log with correlation id matching *

ExecTime   	 Monitored Scope
---------- 	 ------------------------------
 2,282.073 	 Leaving Monitored Scope (DataBinding DataFormWebPart (Cust-K<PII
 2,620.962 	 Leaving Monitored Scope (DataBinding DataFormWebPart (Cust-Ohjeet)).  
16,747.120 	 Leaving Monitored Scope (Request (GET:https://msftvrungeb3.sharepoint.com/sites/blah/<Default.aspx)).  

3 monitored scopes matched, for a total of 21650.16 ms

---------------------------------------------------------------------------------------------


Extracting Execution Times above 2000 ms from file C:\vincent\tests\PS_Dump-ExecutionTime\Ignacio Verbose-c526639c-dfb5-80f4-81cd-454bf6cc3828.log with correlation id ma
tching *

ExecTime   	 Monitored Scope
---------- 	 ------------------------------
 8,580.957 	 Leaving Monitored Scope (Scope Name 1).  
 8,581.096 	 Leaving Monitored Scope (This is another scope).  
 8,641.322 	 Leaving Monitored Scope (SharePointForm Control Render).  
14,294.430 	 Leaving Monitored Scope (Request (GET:https://msftvrungeb3.sharepoint.com/Forms/AllItems.aspx)).  

4 monitored scopes matched, for a total of 40097.8 ms

---------------------------------------------------------------------------------------------


Extracting Execution Times above 2000 ms from file C:\vincent\tests\PS_Dump-ExecutionTime\vrunge_88050_ULS.log with correlation id matching *

ExecTime   	 Monitored Scope
---------- 	 ------------------------------
 2,282.073 	 Leaving Monitored Scope (DataBinding DataFormWebPart (blah.  
 2,620.962 	 Leaving Monitored Scope (DataBinding DataFormWebPart (list2).  
16,747.120 	 Leaving Monitored Scope (Request (GET:https://msftvrungeb3.sharepoint.com/sites/>/Default.aspx)).  

3 monitored scopes matched, for a total of 21650.16 ms

---------------------------------------------------------------------------------------------


Processed 3 files

.PARAMETER file
  The ULS file to scan. This parameter is here for simple command line writing.

.PARAMETER files
  a collection of ULS files to scan.
  This is mapped to the pipeline input. So the line below would dump the exec times for all *.log files
     dir *.log | Dump-ExecutionTime.ps1 -Threshold 300

.PARAMETER CorrelationId
  MASK for matching correlation ID, eg "*913f689c-a6dc-d0a4-8cee-724e694865a6*"
  If not specified, all correlation ID will match the default value "*".

.PARAMETER Threshold
  Only Execution time above this value will be considered.
  Threshold is in milliseconds.

.PARAMETER ShowTotalColumn 
  Whether to show the TotalExecTime column.

.NOTES

Event B4LY are logged when the logging for the product "SharePoint Foundation", category "Monitoring"
is set to "High" or more.

.UPDATES
   2014 Feb 02: added split when b4LY events include other info after time

#>

param(
    [Parameter(Mandatory=$false)]
    [string]
    $file 
    ,
    [Parameter(ValueFromPipeline=$true,Mandatory=$false)]
    [string]
    $files 
    ,
    [Parameter(Mandatory=$false)]
    [string]
    $CorrelationId = "*"
    ,
    [Parameter(Mandatory=$false)]
    [single]
    $Threshold = -1.0
    ,
    [Parameter(Mandatory=$false)]
    [switch]
    $ShowTotalColumn
)

# example params
#$file = "u:\tests\PS_Dump-ExecutionTime\vrunge_88050_ULS.log"
#$CorrelationId = "*913f689c-a6dc-d0a4-8cee-724e694865a6*"
#$Threshold = 300


 Begin {
    # Constants and Init
    $TAG_B4LY="*b4ly*"      
    $STR_EXECUTIONTIME = "Execution Time="
    $CULTURE_INFO = [System.Globalization.CultureInfo]"en-US"
    $NUMBER_FORMAT = $CULTURE_INFO.NumberFormat


    function DumpExecTimeForOneFile ($file) {    
    
        [single]$TotalTime = 0.0
        [single]$TotalTimeForSelected = 0.0
        $LinesRead = 0
        $MatchedLine = 0

        # Header of our output
        
        write ""
        "Extracting Execution Times above {0} ms from file {1} with correlation id matching {2}" -f $Threshold, $file, $CorrelationId
        write ""

        if ($ShowTotalColumn) {
            "ExecTime   `tTotalExecTime`t Monitored Scope"  -f ""
            "---------- `t-------------`t ------------------------------"
        } else {
            "ExecTime   `t Monitored Scope"  -f ""
            "---------- `t ------------------------------"
        }


        if ($file) {
            $fh = [System.IO.File]::OpenText($file)
        } else {
            $fh = [System.console]::In
        }


        try {
            for (;;)
            {
                $line = $fh.ReadLine()
                if ($line -eq $null) { break; }

                # tag BG4LY is "Leaving Monitored Scope"

                if ($line -like $TAG_B4LY) {                    $data = $line.Split("`t")
        
                    # Correlation ID should be in $data[8]
                    # Is it our correlation ID ?

                    if ( $data[8] -like $CorrelationId) {                       
                        # Execution time should be in; $data[7]

                        $PosOfExecTime = $data[7].IndexOf($STR_EXECUTIONTIME)

                        if ( $PosOfExecTime -gt 0 ) {

                            $Msg = $data[7].Substring(0, $PosOfExecTime)
                            $TimeStr = $data[7].Substring($PosOfExecTime+$STR_EXECUTIONTIME.Length)

                            #  Sometimes there are other info after the time, eg
                            #  Execution Time=34.6011; CPU Milliseconds=19; SQL Query Count=1
                            $OnlyTimeStr = $TimeStr.Split(";")

                            [single]$ThisTime = 0
                            $ThisTime = $OnlyTimeStr[0].ToDecimal($NUMBER_FORMAT)

                            $TotalTime += $ThisTime

                            # Only output the execution time above the Threshold

                            if ( $ThisTime -gt $Threshold ) {

                                if ($ShowTotalColumn) {
                                    "{0,10:n3} `t {1,11:n3} `t {2} "  -f $ThisTime, $TotalTime, $Msg
                                    } else {
                                    "{0,10:n3} `t {1} "  -f $ThisTime, $Msg
                                    }

                                $MatchedLine++
                                $TotalTimeForSelected += $ThisTime
                            }
               
                       }

                     }

                }   # end IF B4LY

            }  #end FOR
        }finally {
            $fh.Close()
            write ""
            write "$MatchedLine monitored scopes matched, for a total of $TotalTimeForSelected ms"
            write ""
            write "---------------------------------------------------------------------------------------------"
            write ""
        }

     }  # end of function DumpExecTimeForOneFile()

     
     if ($file) {
        DumpExecTimeForOneFile($file)
        [int]$fileCount = 1
     } else {
        [int]$fileCount = 0
     }


 }  # end of BEGIN BLOCK


 Process {
    # Executes once for each pipeline object
    

     foreach ($Onefile in $files) {
        if ($OneFile) {
            DumpExecTimeForOneFile($Onefile)
            $fileCount++
        }
     }

}  # end of PROCESS block

 

 End {
    # Executes once after last pipeline object is processed
    write ""
    write "Processed $fileCount files"
 }


